#!/usr/env python
# Rob Dennis - Arclite EMP
# Keasby - TV renamer
# Project Homepage: http://code.google.com/p/keasby/

import logging
import time

from functools import wraps

log = logging.getLogger("keasby.toolbox")

def timeit(method):
    """
    Prints the execution time for a function
    """
    def timed(*args, **kw):
        ts = time.time()
        result = method(*args, **kw)
        te = time.time()

        log.debug('result: %2.2f sec', (te-ts))
        return result

    return timed

def trace(func):
    """
    trace function suitable for use as a decorator
    """
  
    def _callf(*args, **kwargs):
        # string method for join returns "" if 
        # the iterable is of length 0
        str_args = ", ".join([str(arg) for arg in args])
        str_kwargs = ", ".join(["%s=%s"%(str(k), str(v))
                                    for k, v in kwargs.iteritems()])
        # a string of "" evaluates to False
        str_text = ", ".join([text for text in [str_args, str_kwargs] 
                                if text])
        func_sig = "%s(%s)"%(func.__name__, str_text)

        # your choice, but depending on the amount of
        # debug output this needs to be annoying enough 
        # to stand out 
        trace_start_prefix = "TRACE START: "
        
        try:
            log.debug("%s%s", trace_start_prefix, func_sig)
            r = func(*args, **kwargs)
        
        except Exception, msg:
            # special output in the case of an exception
            if str(msg):
                log.warning("error in: %s: %s -> '%s'", func_sig,
                                 msg.__class__.__name__, msg)
            else:
                log.warning("error in: %s: %s", func_sig,
                                 msg.__class__.__name__)
            raise
            
        trace_end_prefix = "TRACE END: "
        # the trace end should probably include the name,
        # etc. in the case of nested traces (a traced
        # function calls  another traced function)
        
        if r is None:
            log.debug("%s%s", trace_end_prefix, func_sig)
        else:
            # special output in the case of a return value
            log.debug("%s%s = %s", trace_end_prefix, func_sig, r)
        # return whatever the function returns                      
        return r

    return _callf
    
def log_debug(logger_inst):
    """
    sets the log level to DEBUG for the life of the function
    """
    def inner_log_debug(func):
        def set_debug(*args, **kwargs):
            old_level = logger_inst.getEffectiveLevel()
            logger_inst.setLevel(logging.DEBUG)
            logger_inst.debug("-manually set debug log level")
            try:
                r = func(*args, **kwargs)
            finally:
                ##ensuring the log level is reset in case of Exception
                logger_inst.debug("+resetting log level")
                logger_inst.setLevel(old_level)
                
            return r
        return wraps(set_debug)(set_debug)
        
    return inner_log_debug
            